![ECS Execの有効化が原因でECSタスクがPROVISIONING状態から遷移しなくなった話](https://devio2023-media.developers.io/wp-content/uploads/2019/05/amazon-elastic-container-service.png)
ECS Execの有効化が原因でECSタスクがPROVISIONING状態から遷移しなくなった話
CX事業本部@大阪の岩田です。
先日ある環境でECSのタスクがPROVISIONING状態のまま固まって(PENDINGではないのがポイントです!)起動できなくなるという問題が発生しました。※正確にいうとPROVISIONING状態で30分程度固まる→STOPPEDに遷移→新しいタスクがPROVISIONINGされ再度30分程度固まり...という状況です。
最初はNATゲートウェイ周りの設定漏れやECRのVPCエンドポイント設定漏れに起因したよくある問題かと思っていたのですが、色々調査しても一向に原因が分かりませんでした。最終的にECS Execの有効化が原因だったことが分かったので、同じ事象でハマる人が出ないように改めてブログにまとめてみました。
結論
先に結論ですがECS Execを有効化したECSサービスでAuto Scaling グループキャパシティープロバイダーを利用するとタスクが起動できなくなるようです。ドキュメントに記載されている以下の制限事項に抵触するためと思われます。
ECS Exec は現在、Auto Scaling グループのキャパシティープロバイダーを使用して起動されたタスクに対応していません。
環境など
問題が発生していた環境はざっくり以下のような環境でした
- ECS on EC2を利用
- ネットワークモードはdefault(bridge)
- 特にタスク配置戦略やタスク配置の制限は設定されていない
- ASG配下のEC2インスタンスが5台起動していて、クラスタ全体で見るとCPUやメモリは余裕がある状態
- 3つのECSサービスが存在する ※ECSサービスA~Cとします。
- これらのECSサービスは全て同一のコンテナイメージを利用する
事象
この環境下で、ある時点からECSサービスAのタスクが起動できなくなりました。ただし、この状態でもECSサービスB,Cに関してはタスク数を増やすと普通にタスクが起動できる状態です。状況を詳しく確認するとECSタスクがPROVISIONINGのまま一向に進まない状態です。
Stopped状態のタスクのログを確認しても何もログが出力されていません。
ECSサービスのイベントを見てもservice <サービス名> has started 1 tasks: task <タスクID>.
というログが続くだけで、特にエラーログのようなものは出力されていませんでした。
AWSのナレッジセンターの記述を参考に1つ1つ原因候補を潰していきましたが、特に原因らしきものは見つかりませんでした。
Amazon ECS タスクが保留状態のまま止まっているのはなぜですか?
その後色々あってサービスAにECS Execを有効化する更新が入っていたことが判明したため、改めてECS Execの無効化を試行すると無事にタスクが起動できるようになりました。その後ECS Execに関するドキュメントを確認すると結論のセクションで記載した通りAuto Scaling グループキャパシティープロバイダーはECS Execに非対応という記述が見つかりました。
検証してみる
ECS Execの有効化が原因のようだと切り分けられたので、改めて検証してみます。
まず以下のCFnテンプレートを使ってECS関連のリソースをまとめてデプロイします。これはCloudFormationのドキュメント記載のAmazon Elastic Container Service テンプレートスニペット ほぼそのままです。ECS Execに対応した環境を利用したいので、AMI IDの部分だけ本日時点での最新版ami-0ed1560bb509908b1に変更しています。
AWSTemplateFormatVersion: 2010-09-09 Parameters: KeyName: Type: 'AWS::EC2::KeyPair::KeyName' Description: Name of an existing EC2 KeyPair to enable SSH access to the ECS instances. VpcId: Type: 'AWS::EC2::VPC::Id' Description: Select a VPC that allows instances to access the Internet. SubnetId: Type: 'List<AWS::EC2::Subnet::Id>' Description: Select at least two subnets in your selected VPC. DesiredCapacity: Type: Number Default: '1' Description: Number of instances to launch in your ECS cluster. MaxSize: Type: Number Default: '1' Description: Maximum number of instances that can be launched in your ECS cluster. InstanceType: Description: EC2 instance type Type: String Default: t2.micro AllowedValues: - t2.micro - t2.small - t2.medium - t2.large - m3.medium - m3.large - m3.xlarge - m3.2xlarge - m4.large - m4.xlarge - m4.2xlarge - m4.4xlarge - m4.10xlarge - c4.large - c4.xlarge - c4.2xlarge - c4.4xlarge - c4.8xlarge - c3.large - c3.xlarge - c3.2xlarge - c3.4xlarge - c3.8xlarge - r3.large - r3.xlarge - r3.2xlarge - r3.4xlarge - r3.8xlarge - i2.xlarge - i2.2xlarge - i2.4xlarge - i2.8xlarge ConstraintDescription: Please choose a valid instance type. Mappings: AWSRegionToAMI: us-east-1: AMIID: ami-09bee01cc997a78a6 us-east-2: AMIID: ami-0a9e12068cb98a01d us-west-1: AMIID: ami-0fa6c8d131a220017 us-west-2: AMIID: ami-078c97cf1cefd1b38 eu-west-1: AMIID: ami-0c9ef930279337028 eu-central-1: AMIID: ami-065c1e34da68f2b02 ap-northeast-1: AMIID: ami-0ed1560bb509908b1 #AMIID: ami-02265963d1614d04d ap-southeast-1: AMIID: ami-0b68661b29b9e058c ap-southeast-2: AMIID: ami-00e4b147599c13588 Resources: ECSCluster: Type: 'AWS::ECS::Cluster' EcsSecurityGroup: Type: 'AWS::EC2::SecurityGroup' Properties: GroupDescription: ECS Security Group VpcId: !Ref VpcId EcsSecurityGroupHTTPinbound: Type: 'AWS::EC2::SecurityGroupIngress' Properties: GroupId: !Ref EcsSecurityGroup IpProtocol: tcp FromPort: 80 ToPort: 80 CidrIp: 0.0.0.0/0 EcsSecurityGroupSSHinbound: Type: 'AWS::EC2::SecurityGroupIngress' Properties: GroupId: !Ref EcsSecurityGroup IpProtocol: tcp FromPort: 22 ToPort: 22 CidrIp: 0.0.0.0/0 EcsSecurityGroupALBports: Type: 'AWS::EC2::SecurityGroupIngress' Properties: GroupId: !Ref EcsSecurityGroup IpProtocol: tcp FromPort: 31000 ToPort: 61000 SourceSecurityGroupId: !Ref EcsSecurityGroup CloudwatchLogsGroup: Type: 'AWS::Logs::LogGroup' Properties: LogGroupName: !Join - '-' - - ECSLogGroup - !Ref 'AWS::StackName' RetentionInDays: 14 taskdefinition: Type: 'AWS::ECS::TaskDefinition' Properties: Family: !Join - '' - - !Ref 'AWS::StackName' - '-ecs-demo-app' ContainerDefinitions: - Name: simple-app Cpu: '10' Essential: 'true' Image: 'httpd:2.4' Memory: '300' LogConfiguration: LogDriver: awslogs Options: awslogs-group: !Ref CloudwatchLogsGroup awslogs-region: !Ref 'AWS::Region' awslogs-stream-prefix: ecs-demo-app MountPoints: - ContainerPath: /usr/local/apache2/htdocs SourceVolume: my-vol PortMappings: - ContainerPort: 80 - Name: busybox Cpu: 10 Command: - >- /bin/sh -c "while true; do echo '>html< >head< >title<Amazon ECS Sample App>/title< >style<body {margin-top: 40px; background-color: #333;} >/style< >/head<>body< >div style=color:white;text-align:center< >h1<Amazon ECS Sample App>/h1< >h2<Congratulations!>/h2< >p<Your application is now running on a container in Amazon ECS.>/p<' < top; /bin/date < date ; echo '>/div<>/body<>/html<' < bottom; cat top date bottom < /usr/local/apache2/htdocs/index.html ; sleep 1; done" EntryPoint: - sh - '-c' Essential: false Image: busybox Memory: 200 LogConfiguration: LogDriver: awslogs Options: awslogs-group: !Ref CloudwatchLogsGroup awslogs-region: !Ref 'AWS::Region' awslogs-stream-prefix: ecs-demo-app VolumesFrom: - SourceContainer: simple-app Volumes: - Name: my-vol ECSALB: Type: 'AWS::ElasticLoadBalancingV2::LoadBalancer' Properties: Name: ECSALB Scheme: internet-facing LoadBalancerAttributes: - Key: idle_timeout.timeout_seconds Value: '30' Subnets: !Ref SubnetId SecurityGroups: - !Ref EcsSecurityGroup ALBListener: Type: 'AWS::ElasticLoadBalancingV2::Listener' DependsOn: ECSServiceRole Properties: DefaultActions: - Type: forward TargetGroupArn: !Ref ECSTG LoadBalancerArn: !Ref ECSALB Port: '80' Protocol: HTTP ECSALBListenerRule: Type: 'AWS::ElasticLoadBalancingV2::ListenerRule' DependsOn: ALBListener Properties: Actions: - Type: forward TargetGroupArn: !Ref ECSTG Conditions: - Field: path-pattern Values: - / ListenerArn: !Ref ALBListener Priority: 1 ECSTG: Type: 'AWS::ElasticLoadBalancingV2::TargetGroup' DependsOn: ECSALB Properties: HealthCheckIntervalSeconds: 10 HealthCheckPath: / HealthCheckProtocol: HTTP HealthCheckTimeoutSeconds: 5 HealthyThresholdCount: 2 Name: ECSTG Port: 80 Protocol: HTTP UnhealthyThresholdCount: 2 VpcId: !Ref VpcId ECSAutoScalingGroup: Type: 'AWS::AutoScaling::AutoScalingGroup' Properties: VPCZoneIdentifier: !Ref SubnetId LaunchConfigurationName: !Ref ContainerInstances MinSize: '1' MaxSize: !Ref MaxSize DesiredCapacity: !Ref DesiredCapacity CreationPolicy: ResourceSignal: Timeout: PT15M UpdatePolicy: AutoScalingReplacingUpdate: WillReplace: 'true' ContainerInstances: Type: 'AWS::AutoScaling::LaunchConfiguration' Properties: ImageId: !FindInMap - AWSRegionToAMI - !Ref 'AWS::Region' - AMIID SecurityGroups: - !Ref EcsSecurityGroup InstanceType: !Ref InstanceType IamInstanceProfile: !Ref EC2InstanceProfile KeyName: !Ref KeyName UserData: !Base64 'Fn::Join': - '' - - | #!/bin/bash -xe - echo ECS_CLUSTER= - !Ref ECSCluster - |2 >> /etc/ecs/ecs.config - | yum install -y aws-cfn-bootstrap - '/opt/aws/bin/cfn-signal -e $? ' - ' --stack ' - !Ref 'AWS::StackName' - ' --resource ECSAutoScalingGroup ' - ' --region ' - !Ref 'AWS::Region' - |+ service: Type: 'AWS::ECS::Service' DependsOn: ALBListener Properties: Cluster: !Ref ECSCluster DesiredCount: '1' LoadBalancers: - ContainerName: simple-app ContainerPort: '80' TargetGroupArn: !Ref ECSTG Role: !Ref ECSServiceRole TaskDefinition: !Ref taskdefinition ECSServiceRole: Type: 'AWS::IAM::Role' Properties: AssumeRolePolicyDocument: Statement: - Effect: Allow Principal: Service: - ecs.amazonaws.com Action: - 'sts:AssumeRole' Path: / Policies: - PolicyName: ecs-service PolicyDocument: Statement: - Effect: Allow Action: - 'elasticloadbalancing:DeregisterInstancesFromLoadBalancer' - 'elasticloadbalancing:DeregisterTargets' - 'elasticloadbalancing:Describe*' - 'elasticloadbalancing:RegisterInstancesWithLoadBalancer' - 'elasticloadbalancing:RegisterTargets' - 'ec2:Describe*' - 'ec2:AuthorizeSecurityGroupIngress' Resource: '*' ServiceScalingTarget: Type: 'AWS::ApplicationAutoScaling::ScalableTarget' DependsOn: service Properties: MaxCapacity: 2 MinCapacity: 1 ResourceId: !Join - '' - - service/ - !Ref ECSCluster - / - !GetAtt - service - Name RoleARN: !GetAtt - AutoscalingRole - Arn ScalableDimension: 'ecs:service:DesiredCount' ServiceNamespace: ecs ServiceScalingPolicy: Type: 'AWS::ApplicationAutoScaling::ScalingPolicy' Properties: PolicyName: AStepPolicy PolicyType: StepScaling ScalingTargetId: !Ref ServiceScalingTarget StepScalingPolicyConfiguration: AdjustmentType: PercentChangeInCapacity Cooldown: 60 MetricAggregationType: Average StepAdjustments: - MetricIntervalLowerBound: 0 ScalingAdjustment: 200 ALB500sAlarmScaleUp: Type: 'AWS::CloudWatch::Alarm' Properties: EvaluationPeriods: '1' Statistic: Average Threshold: '10' AlarmDescription: Alarm if our ALB generates too many HTTP 500s. Period: '60' AlarmActions: - !Ref ServiceScalingPolicy Namespace: AWS/ApplicationELB Dimensions: - Name: LoadBalancer Value: !GetAtt - ECSALB - LoadBalancerFullName ComparisonOperator: GreaterThanThreshold MetricName: HTTPCode_ELB_5XX_Count EC2Role: Type: 'AWS::IAM::Role' Properties: AssumeRolePolicyDocument: Statement: - Effect: Allow Principal: Service: - ec2.amazonaws.com Action: - 'sts:AssumeRole' Path: / Policies: - PolicyName: ecs-service PolicyDocument: Statement: - Effect: Allow Action: - 'ecs:CreateCluster' - 'ecs:DeregisterContainerInstance' - 'ecs:DiscoverPollEndpoint' - 'ecs:Poll' - 'ecs:RegisterContainerInstance' - 'ecs:StartTelemetrySession' - 'ecs:Submit*' - 'logs:CreateLogStream' - 'logs:PutLogEvents' Resource: '*' AutoscalingRole: Type: 'AWS::IAM::Role' Properties: AssumeRolePolicyDocument: Statement: - Effect: Allow Principal: Service: - application-autoscaling.amazonaws.com Action: - 'sts:AssumeRole' Path: / Policies: - PolicyName: service-autoscaling PolicyDocument: Statement: - Effect: Allow Action: - 'application-autoscaling:*' - 'cloudwatch:DescribeAlarms' - 'cloudwatch:PutMetricAlarm' - 'ecs:DescribeServices' - 'ecs:UpdateService' Resource: '*' EC2InstanceProfile: Type: 'AWS::IAM::InstanceProfile' Properties: Path: / Roles: - !Ref EC2Role Outputs: ecsservice: Value: !Ref service ecscluster: Value: !Ref ECSCluster ECSALB: Description: Your ALB DNS URL Value: !Join - '' - - !GetAtt - ECSALB - DNSName taskdef: Value: !Ref taskdefinition
このテンプレートでデプロイしたECSサービスはECS Execが有効化されていないため、AWS CLIからECS Execを有効化しておきます。
aws ecs update-service --cluster クラスタ名 --service サービス名 --enable-execute-command
この時点ではECSサービスの起動タイプはEC2に設定されています。
このままタスクの数を1にしてみましょう。
無事に起動できました。起動タイプ:EC2の状態であればECS Execが有効でもタスクが起動できることが確認できました。一旦タスクの数を0に戻しておきます。
今度は起動タイプ:EC2となっていたところをキャパシティープロバイダー戦略に切り替えてみましょう。キャパシィプロバイダーの定義を作成した後、サービスの設定を更新します。
設定が更新できたら再度タスクの数を1に更新します。すると...タスクがPROVISIONING状態の進まない事象が再現できました
各種ログを確認してみる
無事に?タスクが起動しない状態が再現できましたが、意図せずこの状況を引き起こした場合に気づく術はないのでしょうか?諸々のログを見ていきたいと思います。まずECSタスクとECSサービスのイベントからは前述の通り有用な情報が得られませんでした。
ECSエージェントのログはどうでしょうか?ログレベルをdebugに上げた状態でEC2インスタンスの/var/log/ecs/ecs-agent.logを確認してみます。
level=debug time=2022-10-19T11:43:39Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:43:39Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:43:39Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:43:56Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:43:56Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:43:56Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:43:59Z msg="Skipping publishing container instance status message that was already sent" module=client.go level=debug time=2022-10-19T11:43:59Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:01Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:01Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:01Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:02Z msg="Handling http requestmethodHEADfrom127.0.0.1:45496" module=logging_handler.go level=debug time=2022-10-19T11:44:16Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:16Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:16Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:19Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:19Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:44:19Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:44:26Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:26Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:26Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:32Z msg="Handling http requestmethodHEADfrom127.0.0.1:53362" module=logging_handler.go level=debug time=2022-10-19T11:44:36Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:36Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:36Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:39Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:39Z msg="Received message of type: AckPublishInstanceStatus" module=client.go level=debug time=2022-10-19T11:44:39Z msg="Received AckPublishInstanceStatus from tcs" module=handler.go level=debug time=2022-10-19T11:44:51Z msg="Received message of type: HeartbeatMessage" module=client.go level=debug time=2022-10-19T11:44:51Z msg="ACS activity occurred" module=acs_handler.go level=debug time=2022-10-19T11:44:51Z msg="instance healthcheck result: OK" module=doctor.go level=debug time=2022-10-19T11:44:56Z msg="Instance is idle. No task metrics to report" module=engine.go level=debug time=2022-10-19T11:44:56Z msg="Received message of type: AckPublishMetric" module=client.go level=debug time=2022-10-19T11:44:56Z msg="Received AckPublishMetric from tcs" module=handler.go level=debug time=2022-10-19T11:44:59Z msg="No container health metrics to report" module=client.go level=debug time=2022-10-19T11:44:59Z msg="Received message of type: AckPublishInstanceStatus" module=client.go ...略
特にエラーらしくログは出力されていません。
Event Bridgeに送信されるECSイベントから何か分かったりしないでしょうか?こちらのブログで紹介しているようなやり方でECSイベントをEvent Bridge経由でCW Logsに保管し、ログを確認してみました。
ECS タスクの停止理由を CloudWatch Logs に保管する方法を教えてください
以下のようなログが出力されていました。
{ "version": "0", "id": "ac39557e-a880-4a00-cd3d-a6694581132b", "detail-type": "ECS Task State Change", "source": "aws.ecs", "account": "<AWSアカウントID>", "time": "2022-10-19T02:27:38Z", "region": "ap-northeast-1", "resources": [ "arn:aws:ecs:ap-northeast-1:<AWSアカウントID>:task/<クラスタ名>/428df540a5e2420a9c5b207ba465e1c9" ], "detail": { "attachments": [], "capacityProviderName": "<キャパシティプロバイダー名>", "clusterArn": "<ECSクラスタのARN>", "containers": [], "cpu": "20", "createdAt": "2022-10-19T01:57:36.165Z", "desiredStatus": "STOPPED", "enableExecuteCommand": false, "group": "service:<ECSサービス名>", "launchType": "EC2", "lastStatus": "STOPPED", "memory": "500", "overrides": { "containerOverrides": [] }, "startedBy": "ecs-svc/7648301721650541975", "stoppingAt": "2022-10-19T02:27:38.829Z", "stoppedAt": "2022-10-19T02:27:38.829Z", "stoppedReason": "Task failed to start", "stopCode": "TaskFailedToStart", "taskArn": "<ECSタスクのARN>", "taskDefinitionArn": "<ECSタスク定義のARN>", "updatedAt": "2022-10-19T02:27:38.829Z", "version": 2 } }
stoppedReasonに"Task failed to start"と出力されていますが、これ以上詳細な情報は分からなそうです。残念。
まとめ
ECSタスクがPENDING状態で固まるという状況は何度か経験しており、どうせ類似の事象だろうと高をくくっていたのですが、今回経験した事象はPROVISIONING状態で固まってしまうという事象でした。各種ログを見ても有用な情報は見当たりませんし、ECS Execの有効/無効はマネコンからは判断できないことから、トラブルシューティングとしてはなかなか難易度の高い事象だったのではないでしょうか。同様の事象でハマった方の参考になれば幸いです。